Oops, I accidentally submitted this before finishing running tests locally. Test failures are not intentional; I'll try to figure out what's going on.

Might be #9147

Is there a way to attach a debugger to some of these tests, to step through what's happening? The build process and test suite bootstrapping are quite complex. I've tried opening node_modules/@cspotcode/source-map-support/source-map-support.js, changing stuff, re-running the tests, but it doesn't seem to make a difference.

If I'm reading that issue correctly, jest is relying on incorrect stack traces, ones that do not match V8 / node's behavior?

essentially, yeah. I haven't bothered to attempt to work around it yet, but it might be time now. Should do that first, before landing this PR.

Semi related: #10633, facebook/react#20026

Is there a way to attach a debugger to some of these tests, to step through what's happening?

As long as you run a single test, debugging should work perfectly fine. Multiple tests spawns processes which at least chrome debugger has issues hitting. Can add --run-in-band to avoid

I've updated the snapshots in #9147, might be interesting to apply this diff on top to see if the stacks then agree

one single change, which seems sorta reasonable?

There was another test failure where jest was expecting Error:\n at but we're giving it Error\n at on newer node. The latter matches vanilla node/v8. Looks like I've fixed this bug in source-map-support when running against node 16 and newer. On node 14 and older the bug still exists, but I know what to fix, so I'll do that.

Taking a look at #10633, this PR (or rather #9147), but this doesn't fix it makes the stack trace wrong.

// hubba.test.js
function BadCode() {
  throw new Error('noo');
}

function run(fn) {
  fn();
}

run(BadCode);

$ node hubba.test.js
/Users/simen/repos/jest/hubba.test.js:2
  throw new Error('noo');
  ^

Error: noo
    at BadCode (/Users/simen/repos/jest/hubba.test.js:2:9)
    at run (/Users/simen/repos/jest/hubba.test.js:6:3)
    at Object.<anonymous> (/Users/simen/repos/jest/hubba.test.js:9:1)
    at Module._compile (node:internal/modules/cjs/loader:1105:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1159:10)
    at Module.load (node:internal/modules/cjs/loader:981:32)
    at Function.Module._load (node:internal/modules/cjs/loader:822:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:77:12)
    at node:internal/main/run_main_module:17:47

$  deno run hubba.test.js
error: Uncaught Error: noo
  throw new Error('noo');
        ^
    at BadCode (file:///Users/simen/repos/jest/hubba.test.js:2:9)
    at run (file:///Users/simen/repos/jest/hubba.test.js:6:3)
    at file:///Users/simen/repos/jest/hubba.test.js:9:1

$  yarn jest hubba
 FAIL  ./hubba.test.js
  ● Test suite failed to run

    noo

      1 | function BadCode() {
    > 2 |   throw new Error('noo');
        |         ^
      3 | }
      4 |
      5 | function run(fn) {

      at fn (hubba.test.js:2:9)
      at run (hubba.test.js:6:3)
      at Object.<anonymous> (hubba.test.js:9:1)

Test Suites: 1 failed, 1 total
Tests:       0 total
Snapshots:   0 total
Time:        0.537 s
Ran all test suites matching /hubba/i.

If I run the same test on main

$ yarn jest hubba
 FAIL  ./hubba.test.js
  ● Test suite failed to run

    noo

      1 | function BadCode() {
    > 2 |   throw new Error('noo');
        |         ^
      3 | }
      4 |
      5 | function run(fn) {

      at BadCode (hubba.test.js:2:9)
      at fn (hubba.test.js:6:3)
      at Object.run (hubba.test.js:9:1)

Test Suites: 1 failed, 1 total
Tests:       0 total
Snapshots:   0 total
Time:        0.468 s
Ran all test suites matching /hubba/i.

Note that it's also correct if I disable code transformation (meaning no source map) or just remove the install call. Not sure if the issue is Babel's source maps (which is the transform we use in this repo) or in applying it.

Yeah, might be a bug in Babel actually. The code produced by babel-jest for hubba.test.js above:

"use strict";

function BadCode() {
  throw new Error('noo');
}

function run(fn) {
  fn();
}

run(BadCode);
//# sourceMappingURL=data:application/json;charset=utf-8;base64,eyJ2ZXJzaW9uIjozLCJuYW1lcyI6WyJCYWRDb2RlIiwiRXJyb3IiLCJydW4iLCJmbiJdLCJzb3VyY2VzIjpbImh1YmJhLnRlc3QuanMiXSwic291cmNlc0NvbnRlbnQiOlsiZnVuY3Rpb24gQmFkQ29kZSgpIHtcbiAgdGhyb3cgbmV3IEVycm9yKCdub28nKTtcbn1cblxuZnVuY3Rpb24gcnVuKGZuKSB7XG4gIGZuKCk7XG59XG5cbnJ1bihCYWRDb2RlKTtcbiJdLCJtYXBwaW5ncyI6Ijs7QUFBQSxTQUFTQSxPQUFULEdBQW1CO0VBQ2pCLE1BQU0sSUFBSUMsS0FBSixDQUFVLEtBQVYsQ0FBTjtBQUNEOztBQUVELFNBQVNDLEdBQVQsQ0FBYUMsRUFBYixFQUFpQjtFQUNmQSxFQUFFO0FBQ0g7O0FBRURELEdBQUcsQ0FBQ0YsT0FBRCxDQUFIIn0=

If I run that file with node

$ node -v
v16.15.0
$ node hubba2.js
/Users/simen/repos/jest/hubba2.js:4
  throw new Error('noo');
  ^

Error: noo
    at BadCode (/Users/simen/repos/jest/hubba2.js:4:9)
    at run (/Users/simen/repos/jest/hubba2.js:8:3)
    at Object.<anonymous> (/Users/simen/repos/jest/hubba2.js:11:1)
    at Module._compile (node:internal/modules/cjs/loader:1105:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1159:10)
    at Module.load (node:internal/modules/cjs/loader:981:32)
    at Function.Module._load (node:internal/modules/cjs/loader:822:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:77:12)
    at node:internal/main/run_main_module:17:47
$ node --enable-source-maps hubba2.js
/Users/simen/repos/jest/hubba.test.js:2
  throw new Error('noo');
        ^

Error: noo
    at fn (/Users/simen/repos/jest/hubba.test.js:2:9)
    at run (/Users/simen/repos/jest/hubba.test.js:6:3)
    at Object.<anonymous> (/Users/simen/repos/jest/hubba.test.js:9:1)
    at Module._compile (node:internal/modules/cjs/loader:1105:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1159:10)
    at Module.load (node:internal/modules/cjs/loader:981:32)
    at Function.Module._load (node:internal/modules/cjs/loader:822:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:77:12)
    at node:internal/main/run_main_module:17:47

The interesting part is the second one, running node with --enable-source-maps - you can see the stack is broken in the same way (should be at BadCode, is at fn). Not sure if this bug is in Node's implementation of source maps or in the one's coming out of Babel. Likely culprit is the latter as it's broken in newer source-map-support as well as @cspotcode/source-map-support?

@jridgewell would you be able to comment on this?

I noticed the package.json version declaration was 0.5.13 as opposed to ^0.5.13. Is one preferred, caret or not? Was going to change it to ^0.8.1

@cspotcode caret generally, it is locked due the the issue with names I commented about above 🙂

My hubba script btw has the correct trace in Chrome

So it might be a bug in the algorithm of source-map-support which both Node and @cspotcode/source-map-support has inherited

Hmm, the flag in node is supposed to come from chromium: nodejs/node#29564

EDIT: Sorry @cspotcode, it's unlikely this has anything to do with your PR, but I do think it's blocked by it

What's the likely culprit? Does this still seem like a flaw in the sourcemaps coming from babel? Is jest currently relying on a bug in the old source-map-support implementation?

If we keep the callsite fallback enabled by default, should we add an optional flag to disable that behavior? @SimenB will that work for jest?

That sounds very reasonable!

I tried teaching source-map-support to map names at getEnclosingLineNumber and getEnclosingColumnNumber the way node does. This highlighted another problem with node's sourcemap implementation -- another place where we should be deviating from node. Thankfully, we're already there, because stable @cspotcode/source-map-support never attempts to map enclosing position.

In this example:

it('should fail', done => {
  throw new Error();
});

The first stack frame's getEnclosing*Number() gives us the location of the done identifier, because that is where the function declaration starts. If we attempt to source-map the name at that position, we erroneously believe that the function's name is done. It is not; that is the name of the first argument to the function.

This example is great, because it shows how bad it can be to attempt these imperfect sourcemap checks. In the examples we looked at several days ago, we were mapping to the name of a function at its callsite, not its declared name. Both names referred to the same function. So it was imperfect, but semantically it sorta made sense.

But today's example is much worst: we are mapping to the name of an entirely different function. This isn't merely imperfect, it's flat-out wrong and misleading. done refers to a different function with a different purpose.

The fix is: never attempt to map names at the "enclosing" position. The sourcemap spec, as it is today, can't do that.

I've updated this pull request to use a pre-built tarball of cspotcode/node-source-map-support#41 because I don't want to publish to npm till it has passed all code reviews, and because trying to use a git dependency was failing some yarn integrity checks on CI.

Here is the diff of my changes against #9147
https://github.com/SimenB/jest/compare/bump-source-map-support..cspotcode:cspotcode-source-map-support

Thanks @cspotcode! I'm still unsure if this is safe to land due to the naming error - for better or worse the current stack traces seems more useful to me, even if the new stacks are more correct. "sourcemap doesn't support this" is an unsatisfying answer when the current behavior of Jest does not have the issue (although it has other issues).

Not sure what the best tradeoff here is... And regardless of the stack itself, the potential performance benefit of this migration is appealing, so that alone might be worth it (although I've not run any sort of benchmarks).

Yeah, that's fair, though I still think jest needs to align with the JS language and find a way to convey that useful information with accurate stack traces.

When I talked about avoiding the enclosing position lookup, jest already does not do that. So you're not actually losing anything there.

These changes do not necessarily suppress helpful function names from appearing in stack traces. They merely move which stack frame they appear on.

For example:

function it(fn) {
  fn(); /*B*/
}
it(() => { /*C*/
  throw new Error() /*A*/
});

In this example, we'll still see it in the stack trace. But this bugfix corrects it to appear on the second stack frame instead of the third.

  at fn (line 5) /*A*/
  at it (line 2) /*B*/
  at <anonymous> (line 4) /*C*/

Another hypothetical example: when jest says at Object.strictEqual (__tests__/asset-metadata-tests.js:24:17) and when a developer knows it should say at verifyAssetMetadataTestMacro, there should be a stack trace above this one that says at strictEqual. The useful info is there in the stack, just on a different (correct) frame. Granted, I bet functions in tests are usually anonymous, they don't have descriptive names like this hypothetical.

showing the callsite name instead of the function name -- is arguably wrong. If we change @cspotcode/source-map-support to stop doing the wrong thing, we fix jest but diverge from node. Which I think is a good thing. But it would be nice to have a couple second opinions before I go down this route.

Node's implementation is largely my best guess at what would be a good user experience. If there's consensus in a large community like Jest, that the behavior in source-map-support is better, I think we'd be smart to align the built-in source map support in Node.js with source-map-support (tldr; perhaps you could make a patch proposing the same updates to Node's implementation?).

aside...

I'm also pretty convinced that trying to provide additional context , in the form of a snippet of source code, was a mistake in Node.js' --enable-source-map implementation. I'm pretty sure it's one of the causes of performance issues.

CC: @cspotcode

For aggressively minified code, source-mapping the callsite name might be better, If the minifier mangled the name. But since minifiers usually don't mangle property names, that is not always true.

For un-minified code, the runtime name is likely to be best all the time. Even when the name is changed, it'll typically be something like foo becomes foo1 or _foo, something like that.

So that was my thinking: in the majority of cases, source-mapping callsite name is worse than using runtime name. For minified code it's a toss-up which is better; for unminified code, the runtime name is better.

And I was thinking specifically about the most likely use-cases. Where we want source-mapped stack traces: testing, debugging, server-side stuff. So minified code is not the norm.

In ts-node, the focus is unminified code, since it's TS->JS. I suspect that's usually the focus in jest as well.

This PR is stale because it has been open 90 days with no activity. Remove stale label or comment or this will be closed in 30 days.

This PR is stale because it has been open 90 days with no activity. Remove stale label or comment or this will be closed in 30 days.

This PR was closed because it has been stalled for 30 days with no activity. Please open a new PR if the issue is still relevant, linking to this one.